Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logs from different streams can arrive out of order #401

Merged
merged 2 commits into from
Dec 14, 2018
Merged

Conversation

KnVerey
Copy link
Contributor

@KnVerey KnVerey commented Dec 13, 2018

What are you trying to accomplish with this PR?
Fix a bug in log streaming when we receive logs out of order: when the last line of the last batch was not the newest, we'd re-print the entire last batch indefinitely. It seems this can happen when stdout and stderr are being interspersed. In the screenshot below, the logs appear in the correct order. The blue numbers indicate the order in which we (reliably) get them back from Kubernetes. Unfortunately the API does not let us request streams separately.

image

How is this accomplished?
When we receive a batch of logs, sort them before deduplicating them.

What could go wrong?

  • If a line is fare enough out of order to not appear in the same batch as it would have if it had been in order, it will be permanently skipped.
  • Logs without timestamps will still be printed on every single polling cycle they're returned in, which can be indefinite if such a line occurs in the last second of logs emitted by the container. I think this will actually never happen in practice, since it's only an older version of k8s (1.8 I think?) that is known to emit such lines, and IIRC it happened when logs weren't available yet, so it would not appear inside a batch of actual logs even then.

@KnVerey KnVerey requested review from fw42 and dturn December 13, 2018 17:54
Copy link
Contributor

@fw42 fw42 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Few nitpicks, feel free to ignore. Looks mostly good 👍

next if check_for_duplicate && likely_duplicate?(timestamp)
check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new
parsed_lines = logs.map { |line| split_timestamped_line(line) }
sorted_lines = parsed_lines.sort do |a, b|
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how about something like

sort do |(t1, _), (t2, _)|

then you can avoid the [0] below (and the name t makes it bit more obvious that it's the timestamp that's being sorted by).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'ld probably go so far as to call the timestamp1 and timestamp2

logs.each do |line|
timestamp, msg = split_timestamped_line(line)
next if check_for_duplicate && likely_duplicate?(timestamp)
check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

womp womp lol

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

😆

@@ -62,16 +62,23 @@ def rfc3339_timestamp(time)

def deduplicate(logs)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe this deserves a new name now? sort_and_deduplicate? sort_and_uniq?

sorted_lines.each do |line|
timestamp = line[0]
msg = line[1]
next if likely_duplicate?(timestamp)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm. likely_duplicate? means that timestamp <= @last_timestamp. But how can this ever be true now that we've sorted the logs by timestamp? Or is it possibly true because of a previous call to this method? i.e. an older value of @last_timestamp, not one that was set during this method call?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or is it possibly true because of a previous call to this method

Exactly. We fetch logs (and then process them here) repeatedly, and since the API does not support subsecond granularity, we inevitably sometimes get the same log lines in more than one batch.

end
end

sorted_lines.each do |line|
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sorted_lines.each do |timestamp, msg|

saves you the next two lines

parsed_lines = logs.map { |line| split_timestamped_line(line) }
sorted_lines = parsed_lines.sort do |a, b|
if a[0].nil? || b[0].nil?
0
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm. Not sure I'm following this logic. 0 here means the two elements are treated as equal, right? Why is that what we want? I would have expected something like

if a[0].nil?
  -1
elsif b[0].nil?
  +1
else
  a[0] <=> b[0]
end

or maybe something like

(a[0] || 0) <=> (b[0] || 0)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My thought was that considering them equal was equivalent to leaving them alone, but that's completely wrong. It totally messes up the sort. Since the actual known case where the timestamp is missing is one where that defective line is the first, I think the second suggestion (assuming no timestamp means earliest) is a good approach.

@fw42
Copy link
Contributor

fw42 commented Dec 14, 2018

Thanks for fixing this!

Copy link
Contributor

@dturn dturn left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is ready to ship once you address @fw42 's comments

next if check_for_duplicate && likely_duplicate?(timestamp)
check_for_duplicate = false # logs are ordered, so once we've seen a new one, assume all subsequent logs are new
parsed_lines = logs.map { |line| split_timestamped_line(line) }
sorted_lines = parsed_lines.sort do |a, b|
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'ld probably go so far as to call the timestamp1 and timestamp2

@KnVerey KnVerey merged commit 0311955 into master Dec 14, 2018
@KnVerey KnVerey deleted the streaming_bug branch December 14, 2018 21:34
@KnVerey KnVerey temporarily deployed to rubygems December 14, 2018 23:13 Inactive
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants